Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

RSDK-9345 Deduplicate noisy logs #4564

Open
wants to merge 12 commits into
base: main
Choose a base branch
from

Conversation

benjirewis
Copy link
Member

@benjirewis benjirewis commented Nov 18, 2024

RSDK-9345

Main changes:

  • Stops outputting logs from the same sublogger that have already been output 3 times in the past 10 seconds
  • Outputs an "aggregation" log for any logs deemed noisy (see above point) at the end of 10 seconds before another log is output
  • Parses new disable_log_deduplication JSON flag to potentially disable the logic described in the above two points

Testing changes:

  • Small changes to existing logging tests
  • Adds tests for log entry stringification
  • Adds tests for log entry deduplication

@viambot viambot added safe to test This pull request is marked safe to test from a trusted zone and removed safe to test This pull request is marked safe to test from a trusted zone labels Nov 18, 2024
@viambot viambot added safe to test This pull request is marked safe to test from a trusted zone and removed safe to test This pull request is marked safe to test from a trusted zone labels Nov 19, 2024
@viambot viambot added safe to test This pull request is marked safe to test from a trusted zone and removed safe to test This pull request is marked safe to test from a trusted zone labels Dec 12, 2024
@benjirewis benjirewis changed the title POC dedupe-logs RSDK-9345 Deduplicate noisy logs Dec 12, 2024
@viambot viambot added safe to test This pull request is marked safe to test from a trusted zone and removed safe to test This pull request is marked safe to test from a trusted zone labels Dec 23, 2024
@viambot viambot added safe to test This pull request is marked safe to test from a trusted zone and removed safe to test This pull request is marked safe to test from a trusted zone labels Dec 23, 2024
@viambot viambot added safe to test This pull request is marked safe to test from a trusted zone and removed safe to test This pull request is marked safe to test from a trusted zone labels Dec 23, 2024
@viambot viambot added safe to test This pull request is marked safe to test from a trusted zone and removed safe to test This pull request is marked safe to test from a trusted zone labels Dec 23, 2024
@viambot viambot added safe to test This pull request is marked safe to test from a trusted zone and removed safe to test This pull request is marked safe to test from a trusted zone labels Dec 23, 2024
logging/impl.go Show resolved Hide resolved
assertLogMatches(t, notStdout,
`2023-10-30T13:19:45.806Z INFO impl logging/impl_test.go:132 foo {"key":"value"}`)

// TODO(benji): Add the following assertions to test more deduplication logic.
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Still working on testing a bit, but thought I'd throw this into review before the holiday.

@viambot viambot added safe to test This pull request is marked safe to test from a trusted zone and removed safe to test This pull request is marked safe to test from a trusted zone labels Dec 23, 2024
@benjirewis benjirewis marked this pull request as ready for review December 23, 2024 21:27
// `recentMessageEntries`, i.e. `LogEntry`s that `String`ify identically should
// be treated as identical with respect to noisiness and deduplication. Should
// not be used for actual writing of the entry to an appender.
func (le *LogEntry) String() string {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

IIUC, this is for computing the key "string" for recentMessageEntries. I don't think this needs any of the special formatting?

Two remarks:

  • If we're going to use this method for creating a special/unique key, let's not call it a String method. For all of the reasons you wrote above -- the consumer of this method requires some crucial properties (great job describing them!). A method named String generally is assumed to not be bound by such strict requirements.
  • But more preferably -- I'm a little concerned about the performance impact of this. More about the number of small allocations rather than CPU time. I'd recommend looking into the hashing functionality Go provides to create a unique identifier for a LogEntry.
    • I don't need to see a benchmark, but I think* Go makes it easy to do memory allocation benchmarks with the -benchmem flag. It that sounds like fun.

}

// Track entry in recentMessage maps.
stringifiedEntry := entry.String()
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

For what it's worth -- this can be computed before acquiring the lock. I don't expect that to a notable impact in the grand scheme of things. But that is a common technique in this type of scenario


// DisableLogDeduplication controls whether to disable de-duplicating noisy
// logs; defaults to false and can be specified in robot config.
DisableLogDeduplication = atomic.Bool{}
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I get why we use this name for the config flag (we want this to be on for robots by default), but I'm curious if you gave any consideration and/or had a reason why this global shouldn't be EnableLogDeduplication/DeduplicateLogs? The two benefits I see:

  • Easier to read symbols in predicates that are in the affirmative
  • The "least surprising behavior" (to a programmer) is for deduplication to be off. I think it's going to be more common to add tests that do not want deduplication. And moreover forget* it's happening. And tests that do need deduplication will know to turn it on.

@@ -304,6 +315,13 @@ func TestSublogger(t *testing.T) {
}

func TestLoggingWithFields(t *testing.T) {
// Disable log deduplication for this test, as it logs "noisily" and makes
// assertions on those logs.
DisableLogDeduplication.Store(true)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think* this could global variable could instead, without loss of generality, be put on the logger registry object? "Registry" certainly doesn't sound like the right name, but I think it's global enough for our purposes. And it would isolate the value for tests.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
safe to test This pull request is marked safe to test from a trusted zone
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants